slf4j-apiのバージョンが1.8系にアップグレードされてログが出力されなくなった

#Java

Satoshi Noto

2017.06.30

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

ある日、気がついたらslf4j-apiのバージョンが1.8系になり、ログが出力されなりました。その際の対応メモです。

結論

先に結論を書いておきます。ログが出力されなくなったのはアプリケーションで利用しているライブラリの中に、slf4j-apiのバージョンを特定のバージョン以上としているライブラリがあったためでした。。そのため、build.gradleのdependencieでそのライブラリをexcludeすることで問題を解消できました。

実行環境

Java 1.8
Gradle 2.12
Tomcat 8

エラー調査

ログが出力されなくなったのでTomcatのcatalina.outを確認した所、以下のログが出力されていました。

SLF4J: No SLF4J providers were found.
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#noProviders for further details.
SLF4J: Class path contains SLF4J bindings targeting slf4j-api versions prior to 1.8.
SLF4J: Ignoring binding found at [jar:file:/var/lib/tomcat8/webapps/ROOT/WEB-INF/lib/logback-classic-1.1.3.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#ignoredBindings for an explanation.

親切にもエラー内容と共にURLも書かれていました。

URLのページを参照した所、SLF4JはJigsaw (Java 9) への対応のため、1.8からServiceLoaderを利用する実装に切り替えたとのことでした。そのため、1.7の形式に対応した実装があっても無視するとのことでした。

しかし、手元のbuild.gradleのslf4j-apiのバージョンは1.7.13でした。。

	compile "org.slf4j:slf4j-api:1.7.13"

そこで./gradlew app:dependenciesでライブラリの依存関係を確認してみた所、確かに1.8.0-alpha2になっていました。

$ ./gradlew app:dependencies
...
+--- org.slf4j:slf4j-api:1.7.13 -> 1.8.0-alpha2
...

おかしいなーと思い、他のライブラリも調べていたら犯人が分かりました。spring-data-mirageを利用していたのですが、このライブラリが犯人でした。

$ ./gradlew app:dependencies
...
|    +--- org.springframework.data:spring-data-mirage:0.3.3.RELEASE
|    |    +--- org.slf4j:slf4j-api:[1.6.2,) -> 1.8.0-alpha2
...

対応

spring-data-mirageが原因だったので、spring-data-mirageについてはdependenciesにおいてslf4j-apiをexcludeするようにしました。

	compile ("org.springframework.data:spring-data-mirage:0.3.3.RELEASE") {
		exclude group: "org.slf4j", module: "slf4j-api"
	}

変更後に./gradlew app:dependenciesでライブラリの依存関係を確認してみた所、1.7.21になっていました。

$ ./gradlew app:dependencies
...
+--- org.slf4j:slf4j-api:1.7.13 -> 1.7.21
...

とりあえず1.7系に下げられたので問題なしと判断し、再度Tomcatにデプロイしたらログが出力されるようになりました。catalina.outもエラーがなくなりlogback.xmlが読み込まれるログに変わっていました。

11:24:18,371 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [/etc/app/logback.xml] at [file:/etc/app/logback.xml]
11:24:18,427 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
11:24:18,439 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Setting ReconfigureOnChangeFilter scanning period to 30 seconds
11:24:18,443 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[/etc/app/logback.xml]] every 30 seconds.
11:24:18,444 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
11:24:18,464 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Adding LoggerContextListener of type [ch.qos.logback.classic.jul.LevelChangePropagator] to the object stack
11:24:18,597 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3ad7350a - Setting level of jul logger [org.apache.catalina.core.ContainerBase.[Catalina].[localhost]] to null
11:24:18,598 |-INFO in ch.qos.logback.classic.jul.LevelChangePropagator@3ad7350a - Propagating DEBUG level on Logger[ROOT] onto the JUL framework
11:24:18,598 |-INFO in ch.qos.logback.classic.joran.action.LoggerContextListenerAction - Starting LoggerContextListener